logbook と loguru でロギングを行ってみよう

LogBookの紹介

logbook は拡張モジュールなので次のようにインストールします。

code: bash pipの場合

$ pip install logbook

使い方は logging とほとんど変わりません。

code: Python

...: from logbook import warning, StreamHandler

...: import sys

...: StreamHandler(sys.stdout).push_application()

...: warning('This is a warning')

...:

LogBook を logging のバックエンドにする

この結果、logging モジュールからみたときには、LogBook の使い方にはほとんど違いはなくなります。

code: Python

...: from logbook import warn, StreamHandler

...: from logbook.compat import redirect_logging

...: redirect_logging()

...: StreamHandler(sys.stdout).push_application()

...: redirect_logging()

...:

...: from logging import getLogger

...: log = getLogger('My Logger')

...: log.warning('This is a warning')

...:

LogBook は次のような目的では選択肢となるでしょう。

既存コードのロギングではパフォーマンスに問題がでてくる

既存コードへの変更点を最小限にしたい

Loguru の紹介

python 標準ライブラリ の logging はよくできていますが、ログ設定ではいくつかの手続きをしなければいけないため、すこし煩雑になりがちです。

これに対して、loguru は驚くほど簡単にロギングできる拡張モジュールで、

デバッグライトとして使用したいときにも適用することができます。

loguru は拡張モジュールなので次のようにインストールします。

code: bash pipの場合

$ pip install loguru

単純な使い方では次のように loguru をインポートするだけです。

code: python

from loguru import logger

logger.debug("That's it, beautiful and simple logging!")

デフォルトの状態ではログは標準出力にも表示されます。

code: python

from loguru import logger

logger.remove()

code: Python

logger.add(sys.stderr,

format="{time} {level} {message}",

filter="my_module", level="INFO")

table: 時間フォーマット指定子

識別子 出力例

年 YYYY 2000, 2001, 2002 … 2012, 2013

YY 00, 01, 02 … 12, 13

クォーター Q 1, 2, 3, 4

月 MMMM January, February, March …

MMM Jan, Feb, Mar …

MM 01, 02, 03 … 11, 12

M 1, 2, 3 … 11, 12

年内の日 DDDD 001, 002, 003 … 364, 365

DDD 1, 2, 3 … 364, 365

月内の日 DD 01, 02, 03 … 30, 31

D 1, 2, 3 … 30, 31

週内の日 dddd Monday, Tuesday, Wednesday …

ddd Mon, Tue, Wed …

d 0, 1, 2 … 6

週内の日（ISO) E 1, 2, 3 … 7

時 HH 00, 01, 02 … 23, 24

H 0, 1, 2 … 23, 24

hh 01, 02, 03 … 11, 12

h 1, 2, 3 … 11, 12

分 mm 00, 01, 02 … 58, 59

m 0, 1, 2 … 58, 59

秒 ss 00, 01, 02 … 58, 59

s 0, 1, 2 … 58, 59

秒の小数部 S 0 1 … 8 9

SS 00, 01, 02 … 98, 99

SSS 000 001 … 998 999

SSSSSS 000000 000001 … 999998 999999

AM / PM A AM, PM

Timezone Z -07:00, -06:00 … +06:00, +07:00

ZZ -0700, -0600 … +0600, +0700

zz EST CST … MST PST

タイムスタンプ（秒） X 1381685817, 1234567890.123

タイムスタンプ（マイクロ秒) x 1234567890123

ログローテーション

code: pyton

logger.add(filepath, rotation="500MB")

"gz", "bz2", "xz", "lzma", "tar", "tar.gz", "tar.bz2", "tar.xz", "zip"　が指定可能

カラー表示

コンソールにログ出力するとき、カラーを指定することができます。

code: python

logger.add(sys.stdout,

colorize=True,

format="<green>{time}</green> <level>{message}</level>")

table: カラーとスタイル

カラー (短縮形) スタイル (短縮形)

Black (k) Bold (b)

Blue (e) Dim (d)

Cyan (c) Normal (n)

Green (g) Italic (i)

Magenta (m) Underline (u)

Red (r) Strike (s)

White (w) Reverse (v)

Yellow (y) Blink (l)

Hide (h)

カラーは小文字で指定すると前景色（文字の色）、大文字で指定すると背景色になります。

他にも次の書式で色指定ができます。

table: 色指定

タイプ 前景色 背景色

基本色 <red> <RED>

<r> <R>

淡色 <light-blue> <LIGHT_BLUE>

<lb> <LB>

8ビット指定 <fg 86> <bg 42>

<fg 255> <bg 9>

RGB指定 <fg 0,95,0> <bg 72,119,65>

環境変数の参照

Linuxでの設定例：

code: bash

export LOGURU_FORMAT="{time}-{message}"

Windowsでの設定例：

code: powershell

setx LOGURU_DEBUG_COLOR "<blue>"

Windowsでアイコンを設定する例：

code: powershe;l

setx LOGURU_TRACE_ICON "🚀"。

code: powershell

LOGURU_DEBUG_COLOR = ^ <blue ^>

例外の捕獲

code: python

@logger.catch

def my_function(x, y, z):

return 1 / (x + y + z)

loguruは、変数の値を含むスタックトレース全体をログできるので、デバッグ時に便利です。

code: test.py

logger.add("output.log", backtrace=True, diagnose=True)

def func(a, b):

return a / b

def nested(c):

try:

func(5, c)

except ZeroDivisionError:

logger.exception("What?!")

nested(0)

このコードは次のようなログを記録します。

code: output.log

2018-07-17 01:38:43.975 | ERROR | __main__:nested:10 - What?!

Traceback (most recent call last):

File "test.py", line 12, in <module>

nested(0)

└ <function nested at 0x7f5c755322f0>

File "test.py", line 8, in nested

func(5, c)

│ └ 0

└ <function func at 0x7f5c79fc2e18>

File "test.py", line 4, in func

return a / b

│ └ 0

└ 5

ZeroDivisionError: division by zero

ログ出力の分離

code: python

from loguru import logger

def do_something():

pass

def do_something_else():

pass

def task_A():

logger_a = logger.bind(task="A")

logger_a.info("Starting task A")

do_something()

logger_a.success("End of task A")

def task_B():

logger_b = logger.bind(task="B")

logger_b.info("Starting task B")

do_something_else()

logger_b.success("End of task B")

logger.add("file_A.log",

logger.add("file_B.log",

task_A()

task_B()

code: bash

$ python loguru_separate.py

2020-04-26 15:07:12.003 | INFO | __main__:task_A:10 - Starting task A

2020-04-26 15:07:12.003 | SUCCESS | __main__:task_A:12 - End of task A

2020-04-26 15:07:12.003 | INFO | __main__:task_B:16 - Starting task B

2020-04-26 15:07:12.004 | SUCCESS | __main__:task_B:18 - End of task B

こうした分離されたログを多数設定してしまうと、それぞれのハンドラーのフィルターによってログをチェックされるため、アプリケーションのパフォーマンスが低下する可能性があります。

code: python

import copy

from loguru import logger

def do_something(id):

pass

def task(task_id, logger):

logger.info("Starting task {}", task_id)

do_something(task_id)

logger.success("End of task {}", task_id)

logger.remove()

logger_ = copy.deepcopy(logger)

logger_.add("file_%s.log" % task_id)

task(task_id, logger_)

tqdm と連携したプログレスバー

tqdmライブラリーによってラップされた反復処理の中で loguruの loggerを使用しようとすると、表示されるプログレスバーが乱れる場合があります。

code: python

import time

from loguru import logger

from tqdm import tqdm

logger.remove()

logger.add(tqdm.write)

logger.info("Initializing")

for x in tqdm(range(100)):

time.sleep(1)

JSON形式でのログ出力

loguru は serialize引数を使用すると、ログメッセージはJSONフォーマットに変換されます。

code: loguru_serialize.py

rom loguru import logger

logger.add('/tmp/test.log', serialize=True)

logger.info("This is first log")

logger.info("This is second log")

code: bash

$ cat /tmp/test.log

{"text": "2020-11-19 11:03:21.775 | INFO | __main__:<module>:5 - This is first log\n", "record": {"elapsed": {"repr": "0:00:00.007473", "seconds": 0.007473}, "exception": null, "extra": {}, "file": {"name": "kk", "path": "kk"}, "function": "<module>", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 5, "message": "This is first log", "module": "kk", "name": "__main__", "process": {"id": 57021, "name": "MainProcess"}, "thread": {"id": 4638453184, "name": "MainThread"}, "time": {"repr": "2020-11-19 11:03:21.775184+09:00", "timestamp": 1605751401.775184}}}

{"text": "2020-11-19 11:03:21.776 | INFO | __main__:<module>:6 - This is second log\n", "record": {"elapsed": {"repr": "0:00:00.009084", "seconds": 0.009084}, "exception": null, "extra": {}, "file": {"name": "kk", "path": "kk"}, "function": "<module>", "level": {"icon": "\u2139\ufe0f", "name": "INFO", "no": 20}, "line": 6, "message": "This is second log", "module": "kk", "name": "__main__", "process": {"id": 57021, "name": "MainProcess"}, "thread": {"id": 4638453184, "name": "MainThread"}, "time": {"repr": "2020-11-19 11:03:21.776795+09:00", "timestamp": 1605751401.776795}}}

このjqコマンドは、Linux, Mac, Windows で使用することができます。

code: bash

% cat /tmp/test.log| jq ".record.message, .record.time"

"This is first log"

{

"repr": "2020-11-19 11:03:21.775184+09:00",

"timestamp": 1605751401.775184

}

"This is second log"

{

"repr": "2020-11-19 11:03:21.776795+09:00",

"timestamp": 1605751401.776795

}

ハンズオン

ログレベルをDEBUGで： 自分の名前

ログレベルをWARRNINGで："Python Osaka"

標準出力を確認してみましょう。

ファイルの内容を確認してみましょう。

標準出力を確認してみましょう。

ファイルの内容を確認してみましょう。

標準出力を確認してみましょう。

ファイルの内容を確認してみましょう。

参考: